Profiling 实战解读：从采集、读数到把变慢钉到单个算子

vLLM 源码 · 2026-10-16 发布 · vllm-ascend NPU Profiling 实战笔记

0. Profiling 能回答什么问题

排查的起点很朴素：同一套 GLM-5.1 服务换了推理镜像后变慢——新镜像（10-09 构建，下文简称 1009）比老镜像（08-15 构建，下文简称 0815）的 TTFT（首 token 时延，用户发出请求到收到第一个字）慢了 15% 至 20%，到底慢在哪个算子上？端侧指标（TTFT/吞吐）只能说明“慢了”，profiling 才能回答“慢在谁身上、慢多少、什么 shape 下慢”。这次它交出的答案：

• 阶段判定：decode 相所有 kernel 两版本无差距 → 排除 decode；
• 算子定位：prefill 相 DispatchFFNCombine（MoE 通信融合算子）的大 chunk 调用变慢——shape [221,6144] P50 3436.9 → 3710.6us（+8%），且 1009 侧出现 p99 11088us 的长尾（单次最大 14.5ms）；
• shape 锁定：慢的调用集中在 220~222 × 6144 的 prefill chunk（decode 形状 1~3 token 无回退）；
• 归因延伸：顺着算子名去对比两版本 CANN 自定义算子包的 kernel 二进制（staticKey 全 DIFF），把结论钉死在“算子包实现变更”上。

没有 profiling，这个故事到“TTFT 慢 15-20%”就断了。

1. 怎么采：vllm serve 里的 --profiler-config + 短窗口姿势

1.1 开关：它是 serve 的独立 CLI 参数

vllm-ascend 采集 NPU profiling 不用改代码，启动时挂上 --profiler-config（注意：独立参数，不是 additional_config 里的字段——放错位置 pydantic 会报 unexpected keyword）：

--profiler-config '{"profiler": "torch", "torch_profiler_dir": "/home/ywx1279670/profile", "torch_profiler_with_stack": false}'

• profiler: "torch"：走 torch_npu profiler 路线（另有 mstx 等），导出 Ascend 侧解析结果；
• torch_profiler_dir：数据落盘目录，确保所在盘有几十 GB 空闲；
• torch_profiler_with_stack: false：不采调用栈。带栈的体积和噪声都大，定位 kernel 级问题不需要它。

1.2 短窗口姿势：这次最重要的一条经验

第一次全量采集直接干出 257GB，几乎导不动也析不动。后来固化成“压测中段 + 15 秒短窗口”的姿势，三个窗口 du -sh 实测 13GB / 14GB / 18GB（-93%），ASCEND 输出解析约 1.5 分钟：

1.3 其他实操要点

• 只采一个 rank 就够入门：DP/EP 下每 rank 是一份完整 shard 的执行记录，定位单算子慢，先看 rank0（dp0_pp0_tp0），需要看通信对齐再扩到多 rank。
• prefill / decode 分窗口采：这次就是分两次采的——decode 窗口 1010_cc8_mlapo、prefill 窗口 1010_cc8_prefill2（目录名＝采集日期_压测档_用途），天然把阶段分开，省得在一份数据里按 step 猜阶段。
• 对照组条件对齐：基线（0815 镜像）与劣化（1009 镜像）用同一套压测参数（输入 3.5K + 输出 1.5K token、32 个请求、并发 8、不限发送速率）、同样窗口长度、同 rank，否则对比没有意义。

2. 采完长什么样：目录结构与每个文件的用途

这次的真实路径与体积（du -sh / ls -lh 实测）：

/home/ywx1279670/profile/
├── 1010_cc8_mlapo/                                        # 1009 decode 短窗口 · 18GB
├── 1010_cc8_prefill2/                                     # 1009 prefill 短窗口 · 14GB
│   └── dp0_pp0_tp0_dcp0_ep0_rank0_289383_20261010221318731_ascend_pt/
│       ├── ASCEND_PROFILER_OUTPUT/                        # ★ 自动解析结果，分析主要就看这里
│       │   ├── kernel_details.csv            209M         # ★ 每个 kernel 的每次执行一行（659657 行）
│       │   ├── ascend_pytorch_profiler_0.db  744M         # 原始时序库（最大的一块）
│       │   ├── task_time.csv                 138M
│       │   ├── communication.json             85M         # 通信时序（看重叠时用）
│       │   ├── operator_details.csv           31M         # host 侧算子明细
│       │   ├── analysis.db                   8.1M
│       │   ├── api_statistic.csv             8.1K        # host 侧 API 统计（很小，直接看）
│       │   ├── op_statistic.csv              4.7K        # ★ 按算子聚合（很小，直接看）
│       │   ├── communication_matrix.json     10K
│       │   ├── step_trace_time.csv          295B         # 每个 step 的计算/通信拆解（一行一条）
│       │   └── analyse.done                  0B          # 解析完成标记
│       └── PROF_*/ host_info.log / device_*.log           # 原始二进制与日志（一般不动）
├── 1010_cc8_0815_prefill/                                 # 0815 prefill 短窗口（对照组）· 13GB
│   └── dp0_pp0_tp0_dcp0_ep0_rank0_165753_20261010232101886_ascend_pt/
│       └── ASCEND_PROFILER_OUTPUT/  (kernel_details.csv 200M · 636120 行，结构同上)
└── parsed_r0/k10_rank0.csv                                # 早期一次采集的解析结果（留存对比用）

两个细节：①目录名里带 dp0_pp0_tp0_dcp0_ep0_rank0（并行布局与 rank）和采集时刻时间戳（如 20261010221318731），对比两份数据前先对时间戳与 rank；②这套工具链导出里没有 profiler_info.json / CHROME_TRACE，不同版本文件清单略有差异，以实际 ls 为准。

3. kernel_details.csv 怎么读：三板斧

3.1 列含义（本例真实表头）

真实表头（两版本一致）：

Device_id, Model ID, Task ID, Stream ID, Name, Type, OP State, Accelerator Core,
Start Time(us), Duration(us), Wait Time(us), Block Num, Mix Block Num, HF32 Eligible,
Input Shapes, Input Data Types, Input Formats, Output Shapes, Output Data Types, Output Formats,
Context ID, aicore_time(us), aic_total_cycles, aic_mac_time

3.2 文件里的实际数据（原样摘录）

kernel_details.csv 前 2 行数据（每行截断，真实内容）——开头都是些 1~3us 的小 kernel：

0,4294967295,43982,47,aclnnInplaceFillScalar_FillAiCore_Fill,Fill,dynamic,AI_VECTOR_CORE,1791641598803750.295,1.560,0,1,0,NO,"""1;""",INT64;INT32,ND;ND,"""9""",INT32,ND,...
0,4294967295,43987,47,aclnnIndex_IndexCheck_IndexCheck,IndexCheck,dynamic,AI_VECTOR_CORE,1791641598804008.502,3.120,256.690000,4,0,NO,"""1;4""",INT64;INT64,ND;ND,N/A,N/A,N/A,...

op_statistic.csv（4.7KB，全文可直接看）前几行——30 秒摸底就看它：DispatchFFNCombine 一家占 40.5%：

Device_id,OP Type,Core Type,Count,Total Time(us),Min Time(us),Avg Time(us),Max Time(us),Ratio(%)
0,DispatchFFNCombine,MIX_AIC,12007,4574397.762,204.794,380.978,14539.16,40.534
0,QuantBatchMatmulV3,MIX_AIC,54036,1378404.569,9.162,25.509,290.756,12.214
0,SparseFlashAttention,MIX_AIC,12469,1284798.358,93.464,103.039,938.124,11.385
0,TransposeBatchMatMul,AI_CORE,24939,549558.977,18.224,22.036,85.243,4.87
0,allgatherAicpuKernel,AI_CPU,249,467424.672,279.793,1877.208,65305.219,4.142
0,MatMulV2,AI_CORE,17212,407542.289,11.863,23.678,223.238,3.611
0,reduce_scatterAicpuKernel,AI_CPU,171,172385.056,246.744,1008.1,5012.683,1.528

step_trace_time.csv（295B，全文就一行）——这个窗口计算为主、通信大半被重叠：

Device_id,Step,Computing,Communication(Not Overlapped),Overlapped,Communication,Free,Stage,Bubble,...
0,,10604437.507,  1318080.581,  38628.661,  1356709.242,  451331.072,  12373849.25, 0,...

读法：窗口总时长约 13.9s，其中 Computing 10.6s（76%），不重叠通信 1.32s（9.5%），Overlapped 仅 38.6ms——说明通信几乎都被计算盖住了，瓶颈在 kernel 执行本身，这也是后面敢把矛头指向单算子耗时的依据之一。

api_statistic.csv 前几行——host 侧视角，看 CPU 侧谁在烧时间：

Device_id,Level,API Name,Time(us),Count,Avg(us),Min(us),Max(us),Variance
host,communication,AivKernel,157403.46,6271,25.1,18.48,70.74,10.974
host,acl,Cast_Tiling,20853.01,1232,16.926,5.18,313.13,289.435
host,acl,ForeachAddList_Tiling,34145.23,1674,20.397,0.63,767.48,1125.884

3.3 分析流程

3.4 pandas 模板（这次分析脚本的骨架，列名按真实文件写）

import pandas as pd, glob

# ---- 取文件：递归找 ASCEND_PROFILER_OUTPUT 下的 kernel_details.csv ----
f = glob.glob("/home/ywx1279670/profile/1010_cc8_prefill2/**/kernel_details.csv",
              recursive=True)[0]
df = pd.read_csv(f)          # 本例 209MB / 659657 行，读入约 1~2 分钟

dur, name, shp = "Duration(us)", "Name", "Input Shapes"

# ---- ① 全局排行：谁总耗时最大（等价于看 op_statistic.csv，但可算分位数）----
top = (df.groupby(name)[dur]
         .agg(cnt="count", total="sum", mean="mean",
              p50=lambda s: s.quantile(.5), p99=lambda s: s.quantile(.99))
         .sort_values("total", ascending=False).head(20))
print(top)

# ---- ② 锁定目标算子，看分布 ----
k = df[df[name].str.contains("DispatchFFNCombine", na=False)]
print(len(k), k[dur].mean(), k[dur].quantile(.5), k[dur].quantile(.99))

# ---- ③ 按 Input Shapes 分组（★关键：不按 shape 拆开看不到真差距）----
k = k.assign(shapes=k[shp].astype(str))
g = (k.groupby("shapes")[dur]
       .agg(cnt="count", mean="mean",
            p50=lambda s: s.quantile(.5), p99=lambda s: s.quantile(.99))
       .sort_values("cnt", ascending=False))
print(g.head(6))

# ---- ④ 两版本对齐对比：同一套聚合分别跑 0815 / 1009 目录后按 shapes 拼表 ----
# cmp = g0815.join(g1009, lsuffix="_0815", rsuffix="_1009")
# 只看“大 chunk”那几行（shapes 里首维 220~222），p50/p99 逐行对比

服务器上当时的分析脚本（/tmp/analyze_tri2.py 三边对比、/tmp/deep_analyse.py shape/重叠深挖）就是这个骨架加上多目录循环和输出整理。下面的实战复盘全部是按这个模板跑出来的真实数字。

4. 实战复盘：从两份 CSV 到“FFNCombine 大 chunk 回退”

按 3.4 的模板把两份 prefill 窗口各跑一遍，下面所有表都是脚本真实输出（本次复核重跑）。

4.1 第一步：全局排行——两版本 top10（按总耗时）

排行本身就有信息量：1009 的集合通信便宜了很多（reduce_scatter 1489→172ms、allgather 1070→467ms，这是 1009 通信优化的收益），FFNCombine 总耗时反而还低了（4772→4574ms，调用次数还多 17%）。单看总量排名，根本发现不了回退——这正是第二步要按分布、第三步要按 shape 拆的原因。

4.2 第二步：锁 DispatchFFNCombine 看分布（全窗口池化）

### DispatchFFNCombine 对比（全窗口池化）
0815 {'cnt': 10218, 'mean': 467.0, 'p50': 304.8, 'p99': 3971.4, 'sum_s': 4.77}
1009 {'cnt': 12007, 'mean': 381.0, 'p50': 276.3, 'p99': 4116.7, 'sum_s': 4.57}

池化口径下 1009 的 p50 / mean 反而更低——因为窗口里混着两类调用：~300us 的 decode 形状小调用（1~3 token）和 3~4ms 的 prefill 大 chunk 调用，两个窗口里两类调用的比例不一样（1009 窗口小调用 11622 次 / 0815 窗口 9672 次），直接池化会被稀释甚至比反。必须按 Input Shapes 拆开。

4.3 第三步：按 Input Shapes 分组（真实输出，本案例的转折点）

### 1009 prefill（按 shape 分组，Duration(us)）
shapes                                                        cnt   mean     p50      p99
1,6144;8,6144,4096;...（decode 形状）                        9672   276.8   275.7    334.0
2,6144;8,6144,4096;...（decode 形状）                        1950   276.6   274.5    385.2
220,6144;8,6144,4096;...（prefill 大 chunk）                  234  4117.6  3972.5  11088.4
221,6144;8,6144,4096;...（prefill 大 chunk）                  151  2613.4  3710.6   4819.7

### 0815 prefill
shapes                                                        cnt   mean     p50      p99
2,6144;8,6144,4096;...（decode 形状）                        7020   303.6   303.8    334.4
3,6144;8,6144,4096;...（decode 形状）                        2652   307.5   305.3    435.7
221,6144;8,6144,4096;...（prefill 大 chunk）                  468  3249.2  3436.9   5544.6
222,6144;8,6144,4096;...（prefill 大 chunk）                   78  3909.8  3623.0   8034.6

5. 坑与经验清单（都是这次交过学费的）

• 数据量失控：全量采集 257GB——务必短窗口（12~15s）、关 with_stack、先查盘空间。
• 窗口没对齐就开比：两份 profile 必须同压测参数、同窗口长度、同 rank；本例没有 profiler_info.json，就核对目录名里的时间戳。
• 只看均值/总量会漏案，池化还会稀释差距：这次 FFNCombine 总耗时 4772→4574ms 反而更低、池化 p50 304.8→276.3 也是更低——直到按 Input Shapes 拆开才看到大 chunk +8%、p99 11088 的长尾。窗口里混着 decode 小调用和 prefill 大 chunk 时，比例不同就会把差距洗掉甚至比反，分布必须带 p50/p99、分组必须到 shape。
• op_statistic.csv 看不到长尾：它是预聚合的，定位分布问题必须回到 kernel_details.csv 明细。
• 阶段不分离会误判：prefill/decode 混在一份数据里，慢算子可能只是 decode 拖尾；分窗口采集（这次的做法）最省心，退而求其次用 shape/step_trace 分。
• 归因要落到物：耗时对比只能说明“哪个算子慢”，要回答“为什么慢”得继续往下挖——对比 kernel 二进制（staticKey / md5）、翻算子包版本变更，或提单给算子团队带上两份 kernel_details.csv。
• 解析工具别恋战：ASCEND_PROFILER_OUTPUT 自动产物优先；msprof --parse=on 失败就换路，别卡死一条道。

姊妹篇：《算子与 vLLM 参数：一条链讲透》——本篇的 profiling 数据反过来用：从算子清单反推启动配置，参数影响算子的四种方式。

注：文中目录名、文件体积、行数与全部统计数字（257GB / 13~18GB / 659657 行 / op_statistic 占比 40.5% / [221,6144] P50 3436.9→3710.6us / [220,6144] p99 11088us / staticKey DIFF 等）为本次排查实测与复核重跑的真实输出；当年报告口径为 220~222 池化 P50 3469→3963us（+14%），两者方向一致、幅度随分组口径略有差异。